ZLogger v2の新ストラクチャードロギング体験

ゆで卵を食べるときは塩をかけるのと同じように、サーバを書くときはストラクチャードロギングをするのが当たり前といった状況になった昨今。世界のロガーたちはキー/バリュー形式の構造化データを出力すべく、その用途に特化したインターフェイスを獲得するに至っている。

一方、プログラミング言語やフレームワークによってはこの辺のサポートはけっこうまちまちで、人によってストラクチャードロギングに対しての理解度やロガーへの要求水準はけっこう違っているようである。

私がサーバを書く仕事を始めた頃なんかは、使っていたウェッブフレームワークはさも当然のように人間にとって読みやすく整形された文字列をログに吐いた。ほかにオプションはなかった。私は「ふーん。そんなもんかな」と思いながら、ログを上から下に読んでいたが、しかしこれは一件のログレコードが改行されまくっていたので、キーワードでgrepするだけで当然のようにぶっ壊れた。

今ではアプリケーションのログというもののありかたはけっこう変わっている。解析するツールやプラットフォームも進化したし、トレースだのメトリクスだのといったその他Telemetry的な情報と関連づけられた最も粒度が細かく信頼性の高いイベントデータ、それがログである、ということになっている。アプリケーションのロジックを知っていて欠損率も低いイベントデータとして、いろいろな用途の情報源としての潜在能力も高い。

当時、隣の席にいた同僚は LTSVというフォーマットを発見し、「ヒューマンリーダブルかつマシンリーダブルなフォーマットでログを吐くのって、『良い』よね」みたいなことを控えめに言っていた記憶があるのだが、しかし私はその後、LTSVを本番で使うことはなかった。

つくるシステムが複雑化、または大規模化し、とんでもない量のログがアンデス山脈の雪崩の五倍くらいの勢いで流れてくるようになると、生ログが人間にとって読み易いかどうかはすぐにどうでもよくなってしまった。

デプロイされた環境のログはパースされ、値の意味を解釈され、フィルタされ、整形されたテーブル形式のUIを通して見る。だから生のログフォーマットへの要求は、人間にとっての読みやすさではなく、どの環境でも完璧に動くパーサがあり、仕様があり、ネストしたデータやコレクションなども表現できる高い表現力、などに移った。

そんなわけで、JSONが最高に素晴しいソリューションなのかについては若干の疑問があるけれど、様々なプラットフォームやロガーの状況を考えると、本番(というかデプロイされた環境)ではログはJSONで吐いとけばまあ間違いがない、というのが現代のログのフォーマット事情となっている。

(ちなみにOpenTelemetryはログをOpenTelemetry protocol (protobuf) で外側にいる collector/agent へpush形式で素朴に投げ飛ばす仕様を持っている。このプロトコルはgRPCなので、この場合のフォーマットはJSONではなくprotobufになる。ただ、アプリケーションと外側のログを直でOTLPでつなげてしまうと、 collector/agent やexport先にダウンタイムをつくるとログが欠損するリスクがあるので注意が必要。アプリケーション側とcolector/agent側にデプロイの依存関係ができてしまうので、ログを欠損させたくないなら(欠損させてよいアプリケーションが世の中にあるのかよくわからないが、)一旦ローカルマシン上のI/Oをある程度即座に行ってexportしておくという構成が妥当だと思う。OTLPに対応したOpenTelemetry Collector とかはデフォルトだと割とこの辺は素朴な構成だったりする。ちなみにOpenTelemetry の LogRecord 仕様とExpoter実装を使いつつも、export先をローカルファイル/標準出力へのI/O にすることは可能だ)

あとDocker Engineのlog driver経由で標準出力をfluentbit につなげたりする場合はJSONしか選択肢がなかったりする場合もやっぱりある)

さてここで、ストラクチャード某ロガーに特に関心のない人はこんな疑問を持つのではないだろうか。

「JSONのログ? そんなの、読めたもんじゃないのではないだろうか？」

そのとおりである。しかし今や、ストラクチャードロガーを名乗る多くのロガーは、人間に読み易いフォーマットと機械に読み易いフォーマットとを切り替える機能を持っている。本番ではJSONを吐くけれど手元のマシンで動かしているときは読みやすいフォーマットを吐く。なんなら色もつけときました、ぜんぶやっときました、といった具合である。

そういう意味で、現代では生データをヒューマンリーダブルかつマシンリーダブルにするのはロガーの仕事になってる。LTSVの仕事ではなく。

私はそこそこ色々な環境でサーバなんかをつくる仕事をしてきたと思うのだが、この分野でC#はけっこう進んでいる。

C#の標準のロガーの抽象レイヤーは、構造化データを出力することが想定されているし、ログの「スコープ」の概念も持っているし、OpenTelemetryのLogRecord仕様を使うこともできる。

ZLoggerは現時点では最も普及しているロガーというわけではないけれど、誰もが当たり前と思っていたログ呼び出し時のGCゴミの発生を劇的に抑制している高速なロガー実装である。

普通に考えると、可変長パラメータをとるログ呼び出しのところはアロケーションが発生するとしか思えへんのだが、どのような工夫でそれを乗り越えているのか、といった点については是非上の記事などを見てほしい。

私が今日紹介したいのは、ZLogegr v2 のストラクチャードロガーとしてのAPIの進化について。

ZLogegr は バージョン2 でさらに汎用的に使えるロガーになったのだが、ログ呼び出しのAPIが現行世代のロガーにはないものに一新された。私はこれはなかなか良い感じだと思うのだが、ふと知り合いにこの辺の話をしてみたところ、「ふーん。そんなものかな」程度のそこそこの反応。「そんなことよりアジャイルコンサルタントが書いた新刊がどうのこうの……」みたいな話題のほうが耳目を集めていることにきがつき、私はここにきてようやく、ストラクチャードロガーのAPIというのものがそこまで広く認知されていないことに思い至った。

そこで以下では、ただのロガーがストラクチャードロガー的な機能を獲得していく様を段階的に追いかけることで、改めてロガーのAPIについて考えていき、 ZLoggerの新しさを明らかにしてみたい。

ストラクチャードロガー Lv 0 文字を入力にとる

ロガーを名乗るライブラリは大抵は以下のようなインターフェイスを持っていると思う。

code:cs

logger.info("冷えたビールで事態の収束を待つ")

ログレベルと出力したい文字列を指定するようになっているデザイン。

このへんがロガーとしては最低現の機能だろう。もちろん、用途によってはべつにこれで充分である。

通常は内部に タイムスタンプなどのメタ情報も保持していて、以下のようなかんじで整形した字を出してくれたりする。

code:log

与えた入力が文字列だけだったとしても、最終的な出力フォーマットを変更できるものもあるようだ。

code:json

{ level: "Information", message: "冷えたビールで事態の収束を待つ", timestamp: "2024-12-31 01:02:03" }

あ、なんだJSONにできんじゃん。しかしこれだけでは胸を張ってストラクチャードロガーを名乗るにはまだ不十分かなと思える。柔道で言えば初段、と言いたいところだが、なんか帯のしめかたがこなれていない、そんな段階だ。

ちなみに、伝統的なロガーは出力先の設定がいろいろと豊富だったりするが、現代ではコンテナで動くサーバは標準出力にログを出しとけばいいじゃん、が解だったりするので、その辺の重要性は下がっていると思う。そのためここでは取り上げない。

ストラクチャードロガー Lv1 キー/バリューを入力に取る

ログを構造化データとして扱うためには、なんらかの方法でロガーを経由して「構造化データ」を入力してあげなければいけない。

データといっても発生するログの文脈ごとに出力したいデータ型は様々なので、その都度動的に任意の型のキー/バリュー形式のデータをつっこめるようになっているとよい。

たとえば golang の zerolog などは以下のような身も蓋もないインターフェイスを持っているようだ。

code:go

log.Debug().

Str("Scale", "833 cents").

Float64("ID", 12345).

Msg("Fibonacci is everywhere")

log.Debug().

Str("Name", "Tom").

Send()

素朴にキー/バリューを指定するだけ。もはや文字列メッセージはあってもなくてもどっちでもよい存在になっている。

rust の slog なんかは、以下のようなマクロが用意されている。

code:rust

info!(logger, "Hello", "name" => "Bob");

最初の引数は文字列メッセージ。以降はキーバリューを任意にいくつでも指定できる。

これが関数ではなくマクロである理由については以降でもう一度取り上げてみようと思う。

おもしろいのは C# の一般的なロガーのインターフェイスである。

code:cs

log.Information("User {username} logged in from {ip_address}", "Bob", "127.0.0.1")

パッと見、文字列テンプレートに変数を埋め込んでいるように見える。

しかし実はこれは、以下の3つの入力を同時にロガーへ与えている。

"User Bob logged in from 127.0.0.1" というテキストメッセージ

キー/バリューを指定するという目的を果たしつつ、旧来のロガーと同様のノリで人間向けにレンダリングされたメッセージも提供してくれるという、アイデアが光るAPIなのである。

ロギングは、本筋の本来書きたいプログラムではなくただの添え物、人間向けのメモみたいなもんなので、ソースコード上では主張が強くなくかつログの意図がパット見でわかる見た目をしているとよい。その観点でいくとこのインターフェイスは優れている。

(C# に明るくない方のために一応補足しておくと、C# には 文字列テンプレートがあるので、ただ文字列を変数から組み立てる場合は上のような書き片はしない。 キーの名前を実行時にロガーに明示的に与えるために、あえて 上の書き方になっているのだ。

ストラクチャードロガー Lv2. 複数フォーマットへの出力

入力にとったキー/バリュー形式のデータはそれ自体は特定のフォーマットに依存していない。上で紹介したロガーはすべて、様々なフォーマットで出力することがでできる。

上で書いたserilog の例を続けるなら、

code:cs

var position = new { Latitude = 25, Longitude = 134 };

var elapsedMs = 34;

log.Information("Processed {@Position} in {Elapsed:000} ms.", position, elapsedMs);

このようにログ出力を書いたソースコードがあったとして、

ローカルの開発環境では↓のように人間が読めるフォーマットをすることもできるし、

code:cs

本番では↓のようにJSONに切り替えることができる。

code:cs

{"Position": {"Latitude": 25, "Longitude": 134}, "Elapsed": 34}

世の中のストラクチャードロガーを名乗るライブラリは大抵はこの辺の機能までは搭載している。ここまでくればストラクチャードロガーを名乗ってももんくはつかない。柔道でいえば地区予選通過である。

テキストメッセージではなく構造化データを自由に入力にとれるようになったが、そうなってくると実用のためにはさらに欲しい機能がでてくる。

ストラクチャードロガー Lv3. スコープの概念

ここで一旦、ログのことは忘れ、RDB のテーブルのことを考えてみてほしい。

これを読んでいる人は、 ユーザのデータが入ったテーブルをつくったことは一回や二回ではないと思う。

仮に、その usersテーブルに入っている1000億件のレコードの中に、nameがBob、idが3 のレコードがあったとする。

あなたが扱ったDBにはuserに関連するテーブルがいっぱいあるはずだ。ゲームならユーザが獲得したアイテムを保存するテーブルもあるだろうし、blogみたいなシステムなら post を保存すテーブルだってあるかもしれない。

今言ったことは全て忘れ、もう一度ログの話題に戻ってきてほしい。

典型的には、ログには trace_id、span_id、リクエストidなどの、いくつかのログのまとまりすべてに漏れなく入っているべきキーが大抵はある。

ストラクチャードロガーを名乗るロガーの多くはこういった問題に対処する能力を持っている。うんうん。

たとえば C# の Microsfot.Extensions.Logging は、using文で括ったブロック内のすべてのログ呼び出しに特定のキー/バリューを付与する機能があります。

以下は公式サイトで紹介されている例。(少し改変)

code:cs

using (logger.BeginScope("{transactionId}", transactionId))

{

logger.LogInformation("Reading value for {id}", id);

var result = await repository.GetAsync(id);

if (result is null)

{

logger.LogWarning("Not found {id}", id);

}

}

この例では、先頭のusing 文 でログのスコープを開始している。このブロックの内側の「Reading value for...」のログにも transactionId がつくし、「not found」 のログにも transactionId がつく。

code:json

{ "level": "Information", "message": "Reading value for 3", id: 3, transactionId; 98765 }

{ "level": "Warning", "message": "Not found 3", id: 3, transactionId; 98765 }

C# の using 文は await を跨いで括ることができるため、webフレームワークもこの機能をmiddlewareで利用していて、request_id のようなものをある程度自動でつけてくれます。Opentelemetrly の SDK を使っていれば trace_idやspan_id も自動でつきます。

さらに言うと、アプリケーションを書いているプログラマが自前でスコープを宣言することも想定されていて、user_idのように、そのアプリケーション固有のスコープを自由に宣言できることは実際とても有用です。

「スコープ」のほか、同様の目的のためにロガーに階層構造を持たせているロガーも存在します。

たとえば先に紹介した rust の slogは、あるロガーの設定を踏襲しつつ、デフォルトで付与されるキー/バリューを追加したロガーインスタンスを新規作成することができるようになってます。

code:rust

let logger = logger.new(o!("user_id" => 3)),

この例では、新しくインスタンス化したロガーを使う限り、必ず user_id=3 がログに書き込まれることが保証されるというわけです。

ストラクチャードロガー Lv4 コンパイル時解析

ここまでストラクチャードロガーのいくつかの機能をおさらいしてみたが、トラディショナルなロガーに比べて随分と実装が複雑そうである。

特に、可変長引数としてキー/バリューを度せるところなんかは、素朴に考えるとボクシングや動的なバッファ確保が避けられなそうだ。素朴に文字列をぶち込むだけのロガーに比べるととても遅そうである。

それに、アプリケーションのログの有用性が高まってくると、ログを出す頻度や一件あたりのデータ量も増えがち。

CPUバウンドな処理のパフォーマンスにそれなりに気を遣っているフレームワークを使っていたとしても、我々がその上で遅いロガー呼び出しを連打、連打、連打、したら、新たなボトルネックを誕生させてしまいかねない。

ここで注目してみたいのは Rust のロガーである。

code:rust

info!(logger, "Hello", "name" => "Tom");

Rustの場合、こういう可変長パラメータをとるものはすべからくマクロになっている。(マクロというのはコンパイル時にソースコードからRustソースコードを展開する機能のこと)

マクロである理由のひとつは、可変長引数パラメータを実行時ではなくコンパイル時に展開することで、実行時のオーバヘッドを減らすためだ。

code:rust

print!("Hello {}!\n", name);

たとえばこれは以下のように展開され、

code:rust

std::io::_print(

// Simplified expansion of format_args!():

std::fmt::Arguments {

}

);

多くの言語がログ呼び出しの可変長パラメータを実行時に解釈するのに対して、コンパイル時にこれを解釈する方式がとれるとパフォーマンスの面では大きめのアドバンテージがある。

このようなコンパイル時最適化機能を持っている言語はRustのほかにもある。C# もそのひとつ。

現在のC# は、Roslynコンパイラのパイプライに割り込んで C#ソースコードから動的にC#ソースコードを展開する機能を持っているが、これは目的としては上記のようなマクロとほぼ一緒といっても過言ではない。

ただこれはUnity専用だし、Microsoft.Extensions.Logging の Abstarctionを完全に無視しているので、サーバサイドとかで広く使えるものではない。

汎用的なロガーのなかで同様の最適化がかかるロガーのひとつが ZLogger の v2である。

以下がZLogger のログ呼び出しのAPIだ。

code:cs

logger.ZLogInformation($"Hello my name is {name}, {age} years old.");

あれ。 もはや 最初に紹介した素朴な文字列ロガーと見分けがまったくつかない。

しかし上記は **コンパイル時** に以下のように展開される。

code:cs

if (logger.IsEnabled(LogLvel.Information))

{

var handler = new ZLoggerInformationInterpolatedStringHandler(30, 2, logger);

handler.AppendLiteral("Hello my name is ");

handler.AppendFormatted<string>(name, 0, null, "name");

handler.AppendLiteral(", ");

handler.AppendFormatted<int>(age, 0, null, "age");

handler.AppendLiteral(" years old.");

}

つまり、ただ文字列を入力に与えているとみせかけて、以下のパラメータすべてをロガーに入力している。

"Hello my name is Bob, age 21 years old" という文字列メッセージ

キーが "name"、バリューが "Bob"のデータ

キーが "age"、バリューが21 のデータ

キーの名前を変更したい場合は以下のようにする。

code:cs

var name = "ボブ";

logger.ZLogInformation($"Hello, {name:@userName}")

goやjsように、ただ単にキー/バリューを渡すインターフェイスに割り切っているロガーもあるが、ZLogger は考えられる限りもっともシンタックスノイズが少ないソースコードで、人間用のメッセージと任意個のキー/バリューを入力できるので、APIとしてはとても強力である。

ロガーの呼び出しは、本来書きたい処理と比べればオマケのようなものなので、ロガー呼び出しが簡素に一行にまとまり、またそれがどんなイベントをロギングしているものなのかがわかるソースコードになっていると見やすい。

その上、コンパイル時に可変長パラメータが解釈され、ボクシングも抑えられている。

おわり

以上、主にロガーのインターフェイスに注目して、基本的な機能から ZLogger v2 の新しいAPIまで紹介してみました。

現状、ストラクチャード某なロガーをあまり深掘りしていない人も、よりストラクチャード某なロガーを試してみるきっかけになれば幸いです。

(ちなみに私は 現在 ZLogger のコミット権を一応もっていて、開発のお手伝いをさせてもらっているのですが、そのことを差し引いてもZLoggerはおすすめのロガーですよ!